Skip to content

Conversation

Stypox
Copy link
Contributor

@Stypox Stypox commented Jul 31, 2025

Resolve-related functions are not called often but still make up for ~3% of execution time for non-repetitive programs (as seen in the first table below, obtained from running the rust snippet at the bottom with n=1). On the other hand, for repetitive programs they become less relevant (I tested the same snippet but with n=100 and got ~1.5%), and it appears that only try_resolve is called more often (see the last two tables).

The first table was obtained by opening the trace file in https://ui.perfetto.dev and running the following query:

select "TOTAL PROGRAM DURATION" as name, count(*), max(ts + dur) as "sum(dur)", 100.0 as "%", null as "min(dur)", null as "max(dur)", null as "avg(dur)", null as "stddev(dur)" from slices union select "TOTAL OVER ALL SPANS (excluding events)" as name, count(*), sum(dur), cast(cast(sum(dur) as float) / (select max(ts + dur) from slices) * 1000 as int) / 10.0 as "%", min(dur), max(dur), cast(avg(dur) as int) as "avg(dur)", cast(sqrt(avg(dur*dur)-avg(dur)*avg(dur)) as int) as "stddev(dur)" from slices where parent_id is null and name != "frame" and name != "step" and dur > 0 union select name, count(*), sum(dur), cast(cast(sum(dur) as float) / (select max(ts + dur) from slices) * 1000 as int) / 10.0 as "%", min(dur), max(dur), cast(avg(dur) as int) as "avg(dur)", cast(sqrt(avg(dur*dur)-avg(dur)*avg(dur)) as int) as "stddev(dur)" from slices where parent_id is null and name != "frame" and name != "step" group by name order by sum(dur) desc, count(*) desc
image

The following two tables show how many resolve spans there per subname/subcategory, and how much time is spent in each. The first is for n=1 and the second for n=100. The query that was used is:

select args.string_value as name, count(*), max(dur), avg(dur), sum(dur) from slices inner join args USING (arg_set_id) where args.key = "args." || slices.name and name = "resolve" group by args.string_value
image image

The snippet I tested with Miri to obtain the above traces is:

fn main() {
    let n: usize = std::env::args().nth(1).unwrap().parse().unwrap();
    let mut v = (0..n).into_iter().collect::<Vec<_>>();
    for i in &mut v {
        *i += 1;
    }
}

r? @RalfJung

@rustbot
Copy link
Collaborator

rustbot commented Jul 31, 2025

r? @petrochenkov

rustbot has assigned @petrochenkov.
They will have a look at your PR within the next two weeks and either review your PR or reassign to another reviewer.

Use r? to explicitly pick a reviewer

@rustbot rustbot added S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. T-compiler Relevant to the compiler team, which will review and decide on the PR/issue. labels Jul 31, 2025
@rustbot
Copy link
Collaborator

rustbot commented Jul 31, 2025

Some changes occurred to the CTFE machinery

cc @RalfJung, @oli-obk, @lcnr

The Miri subtree was changed

cc @rust-lang/miri

Some changes occurred to the CTFE / Miri interpreter

cc @rust-lang/miri

@rustbot rustbot assigned RalfJung and unassigned petrochenkov Jul 31, 2025
@Stypox Stypox force-pushed the add-tracing-to-resolve branch from aaed279 to 035e767 Compare July 31, 2025 20:02
@Stypox
Copy link
Contributor Author

Stypox commented Jul 31, 2025

Now that #144688 has been merged I rebased on master

@bors
Copy link
Collaborator

bors commented Aug 1, 2025

☔ The latest upstream changes (presumably #144773) made this pull request unmergeable. Please resolve the merge conflicts.

@RalfJung
Copy link
Member

RalfJung commented Aug 2, 2025

@rustbot author

@rustbot rustbot removed the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label Aug 2, 2025
@rustbot
Copy link
Collaborator

rustbot commented Aug 2, 2025

Reminder, once the PR becomes ready for a review, use @rustbot ready.

@rustbot rustbot added the S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. label Aug 2, 2025
@Stypox Stypox force-pushed the add-tracing-to-resolve branch from 035e767 to 99769bc Compare August 11, 2025 12:34
@Stypox
Copy link
Contributor Author

Stypox commented Aug 11, 2025

@rustbot ready

@rustbot rustbot added S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. and removed S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. labels Aug 11, 2025
fmease added a commit to fmease/rust that referenced this pull request Aug 11, 2025
…lett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang#144727 (comment).
fmease added a commit to fmease/rust that referenced this pull request Aug 12, 2025
…lett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang#144727 (comment).
fmease added a commit to fmease/rust that referenced this pull request Aug 12, 2025
…lett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang#144727 (comment).
fmease added a commit to fmease/rust that referenced this pull request Aug 12, 2025
…lett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang#144727 (comment).
fmease added a commit to fmease/rust that referenced this pull request Aug 12, 2025
…lett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang#144727 (comment).
Zalathar added a commit to Zalathar/rust that referenced this pull request Aug 12, 2025
…lett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang#144727 (comment).
Zalathar added a commit to Zalathar/rust that referenced this pull request Aug 12, 2025
…lett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang#144727 (comment).
rust-timer added a commit that referenced this pull request Aug 12, 2025
Rollup merge of #145249 - Stypox:_span-to-_trace, r=joshtriplett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in #144727 (comment).
github-actions bot pushed a commit to rust-lang/miri that referenced this pull request Aug 13, 2025
Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang/rust#144727 (comment).
@RalfJung
Copy link
Member

@bors r+ rollup

@bors
Copy link
Collaborator

bors commented Aug 14, 2025

📌 Commit 99769bc has been approved by RalfJung

It is now in the queue for this repository.

@bors bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Aug 14, 2025
bors added a commit that referenced this pull request Aug 14, 2025
Rollup of 13 pull requests

Successful merges:

 - #140434 (rustdoc: Allow multiple references to a single footnote)
 - #142372 (Improve `--remap-path-prefix` documentation)
 - #142741 (Fix unsoundness in some tests)
 - #144515 (Implement `ptr_cast_array`)
 - #144727 (Add tracing to resolve-related functions)
 - #144959 (fix(unicode-table-generator): fix duplicated unique indices)
 - #145179 (Avoid abbreviating "numerator" as "numer", to allow catching typo "numer" elsewhere)
 - #145250 (Add regression test for a former ICE involving helper attributes containing interpolated tokens)
 - #145266 (Reduce some queries around associated items)
 - #145299 (doc test: fix mpsc.rs try_send doc test)
 - #145323 (Port the `#[linkage]` attribute to the new attribute system)
 - #145361 (Suppress wrapper suggestion when expected and actual ty are the same adt and the variant is unresolved)
 - #145372 (resolve: Miscellaneous cleanups)

r? `@ghost`
`@rustbot` modify labels: rollup
@bors bors merged commit 6ac5c28 into rust-lang:master Aug 14, 2025
10 checks passed
@rustbot rustbot added this to the 1.91.0 milestone Aug 14, 2025
rust-timer added a commit that referenced this pull request Aug 14, 2025
Rollup merge of #144727 - Stypox:add-tracing-to-resolve, r=RalfJung

Add tracing to resolve-related functions

Resolve-related functions are not called often but still make up for ~3% of execution time for non-repetitive programs (as seen in the first table below, obtained from running the rust snippet at the bottom with `n=1`). On the other hand, for repetitive programs they become less relevant (I tested the same snippet but with `n=100` and got ~1.5%), and it appears that only `try_resolve` is called more often (see the last two tables).

The first table was obtained by opening the trace file in https://ui.perfetto.dev and running the following query:

```sql
select "TOTAL PROGRAM DURATION" as name, count(*), max(ts + dur) as "sum(dur)", 100.0 as "%", null as "min(dur)", null as "max(dur)", null as "avg(dur)", null as "stddev(dur)" from slices union select "TOTAL OVER ALL SPANS (excluding events)" as name, count(*), sum(dur), cast(cast(sum(dur) as float) / (select max(ts + dur) from slices) * 1000 as int) / 10.0 as "%", min(dur), max(dur), cast(avg(dur) as int) as "avg(dur)", cast(sqrt(avg(dur*dur)-avg(dur)*avg(dur)) as int) as "stddev(dur)" from slices where parent_id is null and name != "frame" and name != "step" and dur > 0 union select name, count(*), sum(dur), cast(cast(sum(dur) as float) / (select max(ts + dur) from slices) * 1000 as int) / 10.0 as "%", min(dur), max(dur), cast(avg(dur) as int) as "avg(dur)", cast(sqrt(avg(dur*dur)-avg(dur)*avg(dur)) as int) as "stddev(dur)" from slices where parent_id is null and name != "frame" and name != "step" group by name order by sum(dur) desc, count(*) desc
```

<img width="1687" height="242" alt="image" src="https://github.com/user-attachments/assets/4d4bd890-869b-40f3-a473-8e4c42b02da4" />

The following two tables show how many `resolve` spans there per subname/subcategory, and how much time is spent in each. The first is for `n=1` and the second for `n=100`. The query that was used is:

```sql
select args.string_value as name, count(*), max(dur), avg(dur), sum(dur) from slices inner join args USING (arg_set_id) where args.key = "args." || slices.name and name = "resolve" group by args.string_value
```

<img width="1688" height="159" alt="image" src="https://github.com/user-attachments/assets/a8749856-c099-492e-a86e-6d67b146af9c" />

<img width="1688" height="159" alt="image" src="https://github.com/user-attachments/assets/ce3ac1b5-5c06-47d9-85a6-9b921aea348e" />

The snippet I tested with Miri to obtain the above traces is:

```rust
fn main() {
    let n: usize = std::env::args().nth(1).unwrap().parse().unwrap();
    let mut v = (0..n).into_iter().collect::<Vec<_>>();
    for i in &mut v {
        *i += 1;
    }
}
```
github-actions bot pushed a commit to rust-lang/miri that referenced this pull request Aug 15, 2025
Rollup of 13 pull requests

Successful merges:

 - rust-lang/rust#140434 (rustdoc: Allow multiple references to a single footnote)
 - rust-lang/rust#142372 (Improve `--remap-path-prefix` documentation)
 - rust-lang/rust#142741 (Fix unsoundness in some tests)
 - rust-lang/rust#144515 (Implement `ptr_cast_array`)
 - rust-lang/rust#144727 (Add tracing to resolve-related functions)
 - rust-lang/rust#144959 (fix(unicode-table-generator): fix duplicated unique indices)
 - rust-lang/rust#145179 (Avoid abbreviating "numerator" as "numer", to allow catching typo "numer" elsewhere)
 - rust-lang/rust#145250 (Add regression test for a former ICE involving helper attributes containing interpolated tokens)
 - rust-lang/rust#145266 (Reduce some queries around associated items)
 - rust-lang/rust#145299 (doc test: fix mpsc.rs try_send doc test)
 - rust-lang/rust#145323 (Port the `#[linkage]` attribute to the new attribute system)
 - rust-lang/rust#145361 (Suppress wrapper suggestion when expected and actual ty are the same adt and the variant is unresolved)
 - rust-lang/rust#145372 (resolve: Miscellaneous cleanups)

r? `@ghost`
`@rustbot` modify labels: rollup
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. T-compiler Relevant to the compiler team, which will review and decide on the PR/issue.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants